textlogger write through #363

pohly · 2023-01-24T10:48:58Z

What this PR does / why we need it:

kubernetes/kubernetes#114672 uses the textlogger for output routing instead of the legacy code in klog. However, this changes the output for unstructured output (gets quoted) and makes it slower (double encoding).

To avoid both, this PR adds an API for setting a logger that can take formatted data from klog and then writes it directly.

Release note:

NONE

This is meant to be used with textlogger for the non-structured log calls to avoid double encoding.

Textlogger can (but doesn't have to) be used to write klog's unstructured output from calls like Infof directly to the output stream. This has two advantages: - traditional output remains exactly the same as before, which is particularly important for multi-line messages because those get quoted otherwise - performance is better because re-encoding the output string is avoided

logicalhan · 2023-01-26T17:57:25Z

/assign @serathius @thockin
/triage accepted

serathius · 2023-01-27T09:55:00Z

Overall comment whether we need this temporary solution to avoid double encoding.

As discussed on WG meeting, I'm not necessary against performance regressions if:

If avoids hacks and allows more simplicity
Doesn't break out performance goals. For K8s our canonical performance benchmark is scalability tests. cc @wojtek-t

pohly · 2023-01-27T10:52:32Z

As discussed on WG meeting, I'm not necessary against performance regressions

It's not just the performance regressions, the output also becomes less readable. Before:

I0127 11:50:17.513183   32691 logger.go:77] Log using Infof, key: value
I0127 11:50:17.513222   32691 logger.go:83] Log with sensitive key, data: {"secret"}

With double encoding:

I0127 11:51:10.937134   33070 logger.go:77] "Log using Infof, key: value\n"
I0127 11:51:10.937207   33070 logger.go:83] "Log with sensitive key, data: {\"secret\"}\n"

I forgot to point that out in the WG meeting.

pohly · 2023-01-27T10:56:01Z

Doesn't break out performance goals. For K8s our canonical performance benchmark is scalability tests.

I consider that the "acceptance test" for logging changes. But I think we should also strive to achieve the same results with as little extra CPU cycles as possible.

serathius · 2023-02-03T09:38:24Z

Overall lgtm, however name WriteKlogBuffer is little contentious. If I understand it will not be a full fledged feature, just a a temporary workaround to avoid double encoding until we migrate k/k to structured logging. At that point it will not be useful and can be removed. Is that right?

If that so WriteKlogBuffer makes somewhat sense as it a workaround for klog. However It would be clearer if it's called something like KlogEncoderBypass or something similar.

Outside of name, I think WriteKlogBuffer comment is somewhat misleading, it nicely documents the function to make it easier for use, however I don't think we should recommend using it. If the motivation that I wrote above it true, than comment should clearly state:

This function is a klog specific workaround to avoid double encoding.
It's only until k/k is migrated to structured logging, after that will be removed.
It should not be used by any other logger, please don't use it

pohly · 2023-02-03T11:07:02Z

If I understand it will not be a full fledged feature, just a a temporary workaround to avoid double encoding until we migrate k/k to structured logging. At that point it will not be useful and can be removed. Is that right?

Unfortunately not. It needs to become part of the klog v2 API, which means we cannot remove it even when Kubernetes itself no longer needs it.

it nicely documents the function to make it easier for use, however I don't think we should recommend using it.

As it has to become officially part of the API, we should treat it like that and document how to use it.

pohly · 2023-02-03T11:10:39Z

I've been thinking about avoiding this public API, but both klog and textlogger are designed to be completely independent from each other. They just share some internal packages.

Moving the klog state into such an internal package wouldn't help: textlogger then could provide an API to install itself there, but it would make textlogger depend on quite a bit of extra baggage - IMHO not a good solution.

serathius · 2023-02-03T11:13:21Z

cc @liggitt @dims who might be interested in the problem

banjoh · 2023-02-08T16:25:19Z

I'm keen to see how this PR progresses. I'm blocked by the same problem. I'm implementing my own logr.Logger and setting it using klog.SetLogger(logger). My log output ends up with newlines like below. NOTE: I'm not using textlogger meaning this issue will affect anyone who implements their own logger, I think.

[evans] $ ./bin/app -v=2
I0208 16:27:50.193136   72871 root.go:58] "Log message from klog\n"
I0208 16:27:50.193154   72871 root.go:59] "Info message from klog with verbosity 1\n"
I0208 16:27:50.193170   72871 root.go:60] "Infof message from klog with verbosity 1: arg1\n"

Without my logger

I0208 16:29:03.835147   73224 root.go:54] Log message from klog
I0208 16:29:03.835168   73224 root.go:55] Info message from klog with verbosity 1
I0208 16:29:03.835196   73224 root.go:56] Infof message from klog with verbosity 1: arg1

FWIW I tested using https://github.com/go-logr/stdr and https://github.com/go-logr/glogr with the same results, as I expected.

pohly · 2023-02-08T17:05:53Z

I'm keen to see how this PR progresses. I'm blocked by the same problem. I'm implementing my own logr.Logger and setting it using klog.SetLogger(logger).

So do you intend to use WriteKlogBuffer in combination with your logger? How? If you just pass through the log output unchanged, won't that lead to a mixture of different formats (klog text format, structured logging from your logger)? Is that desired?

With the intended usage in combination with textlogger, all messages would be using klog text format, so there is no such inconsistency.

banjoh · 2023-02-08T17:19:11Z

This is what I intend to achieve.

I would like to intercept logs (with whatever formatting they are in) and write them to a separate file (not the one created when you pass in log_file, or log_dir). Exploring the library led me to writing my own logr.Logger and passing it to klog.SetLogger(logger) where I'd have my implementation.

You ask why? Our library heavily uses k8s client-go and we would like to grab logs emitted by the library.

If you just pass through the log output unchanged, won't that lead to a mixture of different formats (klog text format, structured logging from your logger)? Is that desired?

I'm looking for the lowest denominator in the framework to intercept the logs and write elsewhere. My logger will not do any formatting. I ended up using textLogger to retain as much of the formatting as possible. By the look of things, WriteKlogBuffer looks promising.

I'm open to suggestions here.

banjoh · 2023-02-08T17:27:57Z

I addition to the k8s client-go dependency, we would like to use klog's verbosity levels. I know logr loggers have the same interfaces but I thought it would be better to sick with one logging implementation.

pohly · 2023-02-08T18:14:34Z

From a brief look at your LogSink implementation it seems that you should be able to use the textlogger directly?

Or what functionality is missing?

banjoh · 2023-02-08T18:53:41Z

Or what functionality is missing?

I'm missing the part where I can "tee" the logs elsewhere (e.g to a file). I added this change to demonstrate what I mean. Ignore the double formatting done by funcr.Formatter. Its there for demonstration purposes only.

Sample invocation

func main() {
	klog.SetLogger(logger.New(logger.Options{
		Verbosity: 1,
	}))
	klog.Info("Hello, world!")
}

Output looks like this

[evans] $ go run main.go
I0208 18:46:40.134371   89450 main.go:12] "Hello, world!\n"
TEE'd LOG:  "level"=0 "msg"="Hello, world!\n"

With your PR, I'd like to see if all I need is to implement WriteKlogBuffer instead of trying to route Info and Error calls to my logger.

banjoh · 2023-02-08T18:56:53Z

// The buffer will contain exactly the same data that klog normally would write
// into its own output stream(s). In particular this includes the header, if
// klog is configured to write one. The callback then can divert that data into
// its own output streams. The buffer may or may not end in a line break.

This comment is what led me to think this change might suite my needs

pohly · 2023-02-08T20:42:00Z

textlogger writes to an io.Writer, set for the config with Output. The (implicit) guarantee is that there will be one Write call per message - I probably should make that explicit in the documentation.

The implementation of that io.Writer can redirect the actual bytes however it wants. I am using that in kubernetes/kubernetes#114672 to write info messages to stdout and error messages to stderr, with buffering of info messages.

pohly · 2023-02-08T20:43:40Z

So if your goal is to redirect output, then both textlogger and this PR will be relevant for you. My point was just that you don't need to wrap textlogger in your own sink for that.

banjoh · 2023-02-09T10:17:40Z

My point was just that you don't need to wrap textlogger in your own sink for that.

Thanks for the call out. I'll adjust my code accordingly.

textlogger writes to an io.Writer, set for the config with Output. The (implicit) guarantee is that there will be one Write call per message - I probably should make that explicit in the documentation.

This will do the trick with my code looking like this now. Its much simpler and cleaner.

type MyWriter struct{}

func (w *MyWriter) Write(p []byte) (n int, err error) {
	// TODO: Tee my logs to other destinations using https://pkg.go.dev/io#MultiWriter
	fmt.Printf("Written: %s", p)
	return 0, nil
}

// Implementation
klog.SetLogger(textlogger.NewLogger(textlogger.NewConfig(
	textlogger.Verbosity(1),
	textlogger.Output(&logger.MyWriter{}),
)))

Written: I0209 10:10:03.647496   14593 root.go:49] "Hello World!\n"
Written: I0209 10:10:03.647514   14593 root.go:50] "Hello World! with verbosity 1\n"

As a side note, setting the output in klog like so klog.SetOutput(&logger.MyWriter{}) does not have my writer called, which I found a bit misleading. I'm not sure in what conditions it should work. Here is a simple example

package main

import (
	"fmt"

	"k8s.io/klog/v2"
)

type MyWriter struct{}
func (w *MyWriter) Write(p []byte) (n int, err error) {
	fmt.Printf("Written: %s", p)
	return 0, nil
}

func main() {
	klog.SetOutput(&MyWriter{})
	klog.Info("Hello, world!")
}

[evans] $ go run main.go
I0209 10:29:53.239060   17318 main.go:19] Hello, world!

I also noticed this comment claiming the textlogger to be experimental. Are there plans to bring the API to stability?

pohly · 2023-02-09T10:44:33Z

As a side note, setting the output in klog like so klog.SetOutput(&logger.MyWriter{}) does not have my writer called, which I found a bit misleading.

~~Was that when you also did klog.SetLogger? When a logger is set, klog should hand over all log entries to that logger and not use the output file.~~

Never mind, I didn't read carefully. SetOutput only has an effect when klog is not configured to write to stderr. With --logtostderr=false it starts using the file, potentially multiple times per log entry (!), once for each severity level. It's really baroque.

I also noticed this comment claiming the textlogger to be experimental. Are there plans to bring the API to stability?

Yes, as soon as we are confident that the API is sane and no longer needs to be changed in incompatible ways. I think it's almost there, only #368 needs to be merged first.

banjoh · 2023-02-20T18:28:00Z

@pohly anyway I can be of assistance here, or is this change waiting for someone to review and give a thumbs up?

pohly · 2023-02-20T19:37:32Z

Someone needs to review and decide whether it's worth adding this to klog.

dims · 2023-03-01T14:20:27Z

Let's not beat ourselves up if WriteKlogBuffer doesn't feel appropriate. it's still in a separate package with a very few set of references, hoping it stays that way:
https://cs.github.com/?scopeName=All+repos&scope=&q=%2Fklog%5C%2Fv2%5C%2Ftextlogger%2F

/approve
/lgtm

k8s-ci-robot · 2023-03-01T14:20:39Z

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: dims, pohly

The full list of commands accepted by this bot can be found here.

The pull request process is described here

Needs approval from an approver in each of these files:

~~OWNERS~~ [dims]

Approvers can indicate their approval by writing /approve in a comment
Approvers can cancel approval by writing /approve cancel in a comment

pohly added 2 commits January 24, 2023 10:24

klog: support writing formatted buffer through logger

81f97ff

This is meant to be used with textlogger for the non-structured log calls to avoid double encoding.

k8s-ci-robot added cncf-cla: yes Indicates the PR's author has signed the CNCF CLA. needs-triage Indicates an issue or PR lacks a `triage/foo` label and requires one. labels Jan 24, 2023

k8s-ci-robot requested review from harshanarayana and thockin January 24, 2023 10:49

k8s-ci-robot added the size/L Denotes a PR that changes 100-499 lines, ignoring generated files. label Jan 24, 2023

k8s-ci-robot assigned serathius and thockin Jan 26, 2023

k8s-ci-robot added triage/accepted Indicates an issue or PR is ready to be actively worked on. and removed needs-triage Indicates an issue or PR lacks a `triage/foo` label and requires one. labels Jan 26, 2023

pohly changed the title ~~RFC: textlogger write through~~ textlogger write through Feb 3, 2023

pohly mentioned this pull request Feb 8, 2023

log: split streams also for text output kubernetes/kubernetes#114672

Merged

3 tasks

banjoh mentioned this pull request Feb 8, 2023

feat: use klog as the default logging library replicatedhq/troubleshoot#1008

Merged

6 tasks

This was referenced Feb 21, 2023

Add collected runtime logs to support bundle archives replicatedhq/troubleshoot#1028

Open

Add meaningful logging to library and CLI applications replicatedhq/troubleshoot#922

Closed

k8s-ci-robot assigned dims Mar 1, 2023

k8s-ci-robot added the lgtm "Looks good to me", indicates that a PR is ready to be merged. label Mar 1, 2023

k8s-ci-robot added the approved Indicates a PR has been approved by an approver from all required OWNERS files. label Mar 1, 2023

k8s-ci-robot merged commit d7fc505 into kubernetes:main Mar 1, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

textlogger write through #363

textlogger write through #363

pohly commented Jan 24, 2023

logicalhan commented Jan 26, 2023

serathius commented Jan 27, 2023

pohly commented Jan 27, 2023 •

edited

Loading

pohly commented Jan 27, 2023

serathius commented Feb 3, 2023

pohly commented Feb 3, 2023

pohly commented Feb 3, 2023

serathius commented Feb 3, 2023

banjoh commented Feb 8, 2023 •

edited

Loading

pohly commented Feb 8, 2023

banjoh commented Feb 8, 2023 •

edited

Loading

banjoh commented Feb 8, 2023 •

edited

Loading

pohly commented Feb 8, 2023

banjoh commented Feb 8, 2023

banjoh commented Feb 8, 2023

pohly commented Feb 8, 2023

pohly commented Feb 8, 2023

banjoh commented Feb 9, 2023 •

edited

Loading

pohly commented Feb 9, 2023 •

edited

Loading

banjoh commented Feb 20, 2023

pohly commented Feb 20, 2023

dims commented Mar 1, 2023

k8s-ci-robot commented Mar 1, 2023

textlogger write through #363

textlogger write through #363

Conversation

pohly commented Jan 24, 2023

logicalhan commented Jan 26, 2023

serathius commented Jan 27, 2023

pohly commented Jan 27, 2023 • edited Loading

pohly commented Jan 27, 2023

serathius commented Feb 3, 2023

pohly commented Feb 3, 2023

pohly commented Feb 3, 2023

serathius commented Feb 3, 2023

banjoh commented Feb 8, 2023 • edited Loading

pohly commented Feb 8, 2023

banjoh commented Feb 8, 2023 • edited Loading

banjoh commented Feb 8, 2023 • edited Loading

pohly commented Feb 8, 2023

banjoh commented Feb 8, 2023

banjoh commented Feb 8, 2023

pohly commented Feb 8, 2023

pohly commented Feb 8, 2023

banjoh commented Feb 9, 2023 • edited Loading

pohly commented Feb 9, 2023 • edited Loading

banjoh commented Feb 20, 2023

pohly commented Feb 20, 2023

dims commented Mar 1, 2023

k8s-ci-robot commented Mar 1, 2023

pohly commented Jan 27, 2023 •

edited

Loading

banjoh commented Feb 8, 2023 •

edited

Loading

banjoh commented Feb 8, 2023 •

edited

Loading

banjoh commented Feb 8, 2023 •

edited

Loading

banjoh commented Feb 9, 2023 •

edited

Loading

pohly commented Feb 9, 2023 •

edited

Loading